[2024-05-28T07:01:37.454736Z] [info] +++ setup notes +++
[2024-05-28T07:01:37.454920Z] [info] Running on openqaworker22:17 (Linux 5.14.21-150500.55.65-default #1 SMP PREEMPT_DYNAMIC Thu May 23 04:57:11 UTC 2024 (a46829d) x86_64)
[2024-05-28T07:01:37.459986Z] [debug] Found ASSET_1, caching Tumbleweed.x86_64-1.0-libvirt-Snapshot20240527.vagrant.libvirt.box
[2024-05-28T07:01:37.472531Z] [info] Downloading Tumbleweed.x86_64-1.0-libvirt-Snapshot20240527.vagrant.libvirt.box, request #306508 sent to Cache Service
[2024-05-28T07:01:47.588751Z] [info] Download of Tumbleweed.x86_64-1.0-libvirt-Snapshot20240527.vagrant.libvirt.box processed:
[info] [#306508] Cache size of "/var/lib/openqa/cache" is 398 GiB, with limit 400 GiB
[info] [#306508] Downloading "Tumbleweed.x86_64-1.0-libvirt-Snapshot20240527.vagrant.libvirt.box" from "https://openqa.opensuse.org/tests/4226795/asset/other/Tumbleweed.x86_64-1.0-libvirt-Snapshot20240527.vagrant.libvirt.box"
[info] [#306508] Content of "/var/lib/openqa/cache/openqa.opensuse.org/Tumbleweed.x86_64-1.0-libvirt-Snapshot20240527.vagrant.libvirt.box" has not changed, updating last use

[2024-05-28T07:01:47.590740Z] [debug] Found ASSET_2, caching Tumbleweed.x86_64-1.0-virtualbox-Snapshot20240527.vagrant.virtualbox.box
[2024-05-28T07:01:47.593537Z] [info] Downloading Tumbleweed.x86_64-1.0-virtualbox-Snapshot20240527.vagrant.virtualbox.box, request #306509 sent to Cache Service
[2024-05-28T07:01:57.692411Z] [info] Download of Tumbleweed.x86_64-1.0-virtualbox-Snapshot20240527.vagrant.virtualbox.box processed:
[info] [#306509] Cache size of "/var/lib/openqa/cache" is 398 GiB, with limit 400 GiB
[info] [#306509] Downloading "Tumbleweed.x86_64-1.0-virtualbox-Snapshot20240527.vagrant.virtualbox.box" from "https://openqa.opensuse.org/tests/4226795/asset/other/Tumbleweed.x86_64-1.0-virtualbox-Snapshot20240527.vagrant.virtualbox.box"
[info] [#306509] Content of "/var/lib/openqa/cache/openqa.opensuse.org/Tumbleweed.x86_64-1.0-virtualbox-Snapshot20240527.vagrant.virtualbox.box" has not changed, updating last use

[2024-05-28T07:01:57.694542Z] [debug] Found ASSET_256, caching openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso.sha256
[2024-05-28T07:01:57.696752Z] [info] Downloading openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso.sha256, request #306511 sent to Cache Service
[2024-05-28T07:02:02.823811Z] [info] Download of openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso.sha256 processed:
[info] [#306511] Cache size of "/var/lib/openqa/cache" is 398 GiB, with limit 400 GiB
[info] [#306511] Downloading "openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso.sha256" from "https://openqa.opensuse.org/tests/4226795/asset/other/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso.sha256"
[info] [#306511] Content of "/var/lib/openqa/cache/openqa.opensuse.org/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso.sha256" has not changed, updating last use

[2024-05-28T07:02:02.825844Z] [debug] Found HDD_1, caching opensuse-Tumbleweed-x86_64-20240527-kde@64bit.qcow2
[2024-05-28T07:02:02.828154Z] [info] Downloading opensuse-Tumbleweed-x86_64-20240527-kde@64bit.qcow2, request #306513 sent to Cache Service
[2024-05-28T07:02:39.576424Z] [info] Download of opensuse-Tumbleweed-x86_64-20240527-kde@64bit.qcow2 processed:
[info] [#306513] Cache size of "/var/lib/openqa/cache" is 398 GiB, with limit 400 GiB
[info] [#306513] Downloading "opensuse-Tumbleweed-x86_64-20240527-kde@64bit.qcow2" from "https://openqa.opensuse.org/tests/4226795/asset/hdd/opensuse-Tumbleweed-x86_64-20240527-kde@64bit.qcow2"
[info] [#306513] Cache size 398 GiB + needed 2.8 GiB exceeds limit of 400 GiB, purging least used assets
[info] [#306513] Purging "/var/lib/openqa/cache/openqa.opensuse.org/opensuse-15.6-x86_64-706.1-minimalx@64bit.qcow2" because we need space for new assets, reclaiming 2.3 GiB
[info] [#306513] Size of "/var/lib/openqa/cache/openqa.opensuse.org/opensuse-Tumbleweed-x86_64-20240527-kde@64bit.qcow2" is 2.8 GiB, with ETag ""6655813f-b39a0000""
[info] [#306513] Download of "/var/lib/openqa/cache/openqa.opensuse.org/opensuse-Tumbleweed-x86_64-20240527-kde@64bit.qcow2" successful (87 MiB/s), new cache size is 399 GiB

[2024-05-28T07:02:39.578476Z] [debug] Found ISO, caching openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso
[2024-05-28T07:02:39.580638Z] [info] Downloading openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso, request #306518 sent to Cache Service
[2024-05-28T07:02:49.676433Z] [info] Download of openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso processed:
[info] [#306518] Cache size of "/var/lib/openqa/cache" is 399 GiB, with limit 400 GiB
[info] [#306518] Downloading "openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso" from "https://openqa.opensuse.org/tests/4226795/asset/iso/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso"
[info] [#306518] Content of "/var/lib/openqa/cache/openqa.opensuse.org/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso" has not changed, updating last use

[2024-05-28T07:02:49.679190Z] [info] Rsync from 'rsync://openqa.opensuse.org/tests' to '/var/lib/openqa/cache/openqa.opensuse.org', request #306519 sent to Cache Service
[2024-05-28T07:02:54.774237Z] [info] Output of rsync:
[info] [#306519] Calling: rsync -avHP --timeout 1800 rsync://openqa.opensuse.org/tests/ --delete /var/lib/openqa/cache/openqa.opensuse.org/tests/
Try 1:
receiving incremental file list

sent 1,755 bytes  received 1,161,723 bytes  775,652.00 bytes/sec
total size is 5,860,197,483  speedup is 5,036.79


[2024-05-28T07:02:54.774396Z] [info] Finished to rsync tests
[2024-05-28T07:02:54.778736Z] [debug] +++ worker notes +++
[37m[2024-05-28T07:02:55.128152Z] [debug] [pid:129823] Current version is 4.6.1716387241.58dd214 [interface v40][0m
[37m[2024-05-28T07:02:55.137945Z] [debug] [pid:129823] git hash in 'opensuse': 05d47c0cd70fd49af462c0598205d097904f46e3[0m
[37m[2024-05-28T07:02:55.151325Z] [debug] [pid:129823] git url in 'opensuse': https://github.com/os-autoinst/os-autoinst-distri-opensuse.git[0m
[37m[2024-05-28T07:02:55.471420Z] [debug] [pid:129823] usingenv DESKTOP=kde[0m
[37m[2024-05-28T07:02:55.471537Z] [debug] [pid:129823] usingenv DISTRI=opensuse[0m
[37m[2024-05-28T07:02:55.471584Z] [debug] [pid:129823] usingenv QEMUCPU=host[0m
[37m[2024-05-28T07:02:55.471628Z] [debug] [pid:129823] usingenv INSTLANG=en_US[0m
[37m[2024-05-28T07:02:55.471671Z] [debug] [pid:129823] usingenv DVD=1[0m
[37m[2024-05-28T07:02:55.471710Z] [debug] [pid:129823] usingenv KDE=1[0m
[37m[2024-05-28T07:02:55.471752Z] [debug] [pid:129823] usingenv ISO=openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso[0m
[37m[2024-05-28T07:02:55.471798Z] [debug] [pid:129823] usingenv ISO_MAXSIZE=4700372992[0m
[37m[2024-05-28T07:02:55.474094Z] [debug] [pid:129823] parse_vars (variables parsed from YAML schedule):[0m
[37m[2024-05-28T07:02:55.474369Z] [debug] [pid:129823] --- {}
  [0m
[37m[2024-05-28T07:02:55.474762Z] [debug] [pid:129823] ---
  - boot/boot_linuxrc
  - installation/first_boot
  [0m
[37m[2024-05-28T07:02:55.474827Z] [debug] [pid:129823] parse_test_suite_data (data parsed from YAML test_data):[0m
[37m[2024-05-28T07:02:55.474920Z] [debug] [pid:129823] --- {}
  [0m
[37m[2024-05-28T07:02:55.476549Z] [debug] [pid:129823] scheduling boot_linuxrc tests/boot/boot_linuxrc.pm[0m
[37m[2024-05-28T07:02:55.477105Z] [debug] [pid:129823] scheduling first_boot tests/installation/first_boot.pm[0m
[2024-05-28T07:02:55.483462Z] [info] [pid:129833] cmdsrv: daemon reachable under http://*:20173/F46TXgXwXVTzH3Fh/
[2024-05-28T07:02:55.485148Z] [info] [pid:129833] Listening at "http://[::]:20173"
Web application available at http://[::]:20173
[37m[2024-05-28T07:02:55.489061Z] [debug] [pid:129823] git hash in 'opensuse/products/opensuse/needles': 9c264ee66e0366e6bfd7b2a1d219ca52ddb44beb[0m
[37m[2024-05-28T07:02:55.505091Z] [debug] [pid:129823] git url in 'opensuse/products/opensuse/needles': git@github.com:os-autoinst/os-autoinst-needles-opensuse.git[0m
[37m[2024-05-28T07:02:55.505241Z] [debug] [pid:129823] init needles from opensuse/products/opensuse/needles[0m
[37m[2024-05-28T07:02:56.174220Z] [debug] [pid:129823] loaded 7144 needles[0m
[37m[2024-05-28T07:02:56.317066Z] [debug] [pid:129823] 129823: channel_out 16, channel_in 15[0m
[37m[2024-05-28T07:02:56.374811Z] [debug] [pid:130043] 130043: cmdpipe 14, rsppipe 17[0m
[37m[2024-05-28T07:02:56.375089Z] [debug] [pid:130043] started mgmt loop with pid 130043[0m
[37m[2024-05-28T07:02:56.434812Z] [debug] [pid:130043] Launching external video encoder: ffmpeg -y -hide_banner -nostats -r 24 -f image2pipe -vcodec ppm -i - -pix_fmt yuv420p -c:v libvpx-vp9 -crf 35 -b:v 1500k -cpu-used 1 'video.webm'[0m
[37m[2024-05-28T07:02:56.504906Z] [debug] [pid:130043] qemu version detected: 7.1.0[0m
[37m[2024-05-28T07:02:56.506551Z] [debug] [pid:130043] running `/usr/bin/chattr +C /var/lib/openqa/pool/17/raid`[0m
[37m[2024-05-28T07:02:56.519735Z] [debug] [pid:130043] Command `/usr/bin/chattr +C /var/lib/openqa/pool/17/raid` terminated with 1
  /usr/bin/chattr: Operation not supported while setting flags on /var/lib/openqa/pool/17/raid[0m
[37m[2024-05-28T07:02:56.519851Z] [debug] [pid:130043] Configuring storage controllers and block devices[0m
[37m[2024-05-28T07:02:56.520426Z] [debug] [pid:130043] running `/usr/bin/qemu-img info --output=json /var/lib/openqa/pool/17/opensuse-Tumbleweed-x86_64-20240527-kde@64bit.qcow2`[0m
[37m[2024-05-28T07:02:56.556417Z] [debug] [pid:130043] running `/usr/bin/qemu-img info --output=json /var/lib/openqa/pool/17/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso`[0m
[37m[2024-05-28T07:02:56.592802Z] [debug] [pid:130043] Initializing block device images[0m
[37m[2024-05-28T07:02:56.593027Z] [debug] [pid:130043] running `/usr/bin/qemu-img create -f qcow2 -F qcow2 -b /var/lib/openqa/pool/17/opensuse-Tumbleweed-x86_64-20240527-kde@64bit.qcow2 /var/lib/openqa/pool/17/raid/hd0-overlay0 42949672960`[0m
[37m[2024-05-28T07:02:56.630477Z] [debug] [pid:130043] Formatting '/var/lib/openqa/pool/17/raid/hd0-overlay0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=42949672960 backing_file=/var/lib/openqa/pool/17/opensuse-Tumbleweed-x86_64-20240527-kde@64bit.qcow2 backing_fmt=qcow2 lazy_refcounts=off refcount_bits=16[0m
[37m[2024-05-28T07:02:56.630605Z] [debug] [pid:130043] running `/usr/bin/qemu-img create -f qcow2 -F raw -b /var/lib/openqa/pool/17/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso /var/lib/openqa/pool/17/raid/cd0-overlay0 4497342464`[0m
[37m[2024-05-28T07:02:56.668279Z] [debug] [pid:130043] Formatting '/var/lib/openqa/pool/17/raid/cd0-overlay0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=4497342464 backing_file=/var/lib/openqa/pool/17/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso backing_fmt=raw lazy_refcounts=off refcount_bits=16[0m
[37m[2024-05-28T07:02:56.668383Z] [debug] [pid:130043] init_blockdev_images: Finished creating block devices[0m
[37m[2024-05-28T07:02:56.669580Z] [debug] [pid:130043] starting: /usr/bin/qemu-system-x86_64 -device VGA,edid=on,xres=1024,yres=768 -only-migratable -chardev ringbuf,id=serial0,logfile=serial0,logappend=on -serial chardev:serial0 -audiodev none,id=snd0 -device intel-hda -device hda-output,audiodev=snd0 -global isa-fdc.fdtypeA=none -m 1536 -cpu host -netdev user,id=qanet0 -device virtio-net,netdev=qanet0,mac=52:54:00:12:34:56 -object rng-random,filename=/dev/urandom,id=rng0 -device virtio-rng-pci,rng=rng0 -boot once=d -device qemu-xhci -device usb-tablet -smp 1 -enable-kvm -no-shutdown -vnc :107,share=force-shared -device virtio-serial -chardev pipe,id=virtio_console,path=virtio_console,logfile=virtio_console.log,logappend=on -device virtconsole,chardev=virtio_console,name=org.openqa.console.virtio_console -chardev pipe,id=virtio_console_user,path=virtio_console_user,logfile=virtio_console_user.log,logappend=on -device virtconsole,chardev=virtio_console_user,name=org.openqa.console.virtio_console_user -chardev socket,path=qmp_socket,server=on,wait=off,id=qmp_socket,logfile=qmp_socket.log,logappend=on -qmp chardev:qmp_socket -S -device virtio-scsi-pci,id=scsi0 -blockdev driver=file,node-name=hd0-overlay0-file,filename=/var/lib/openqa/pool/17/raid/hd0-overlay0,cache.no-flush=on -blockdev driver=qcow2,node-name=hd0-overlay0,file=hd0-overlay0-file,cache.no-flush=on,discard=unmap -device virtio-blk,id=hd0-device,drive=hd0-overlay0,serial=hd0 -blockdev driver=file,node-name=cd0-overlay0-file,filename=/var/lib/openqa/pool/17/raid/cd0-overlay0,cache.no-flush=on -blockdev driver=qcow2,node-name=cd0-overlay0,file=cd0-overlay0-file,cache.no-flush=on,discard=unmap -device scsi-cd,id=cd0-device,drive=cd0-overlay0,serial=cd0[0m
[37m[2024-05-28T07:02:56.677313Z] [debug] [pid:130043] Waiting for 0 attempts[0m
[37m[2024-05-28T07:02:57.677895Z] [debug] [pid:130043] Waiting for 1 attempts[0m
[37m[2024-05-28T07:02:58.678229Z] [debug] [pid:130043] Finished after 2 attempts[0m
[37m[2024-05-28T07:02:58.691391Z] [debug] [pid:130043] Establishing VNC connection to localhost:6007[0m
[37m[2024-05-28T07:02:58.693751Z] [debug] [pid:130043] pointer type 0 0 640 480 -257[0m
[37m[2024-05-28T07:02:58.693825Z] [debug] [pid:130043] led state 0 1 1 -261[0m
[37m[2024-05-28T07:02:58.748745Z] [debug] [pid:130043] Start CPU[0m
[37m[2024-05-28T07:02:58.749208Z] [debug] [pid:130043] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"51734","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"6007","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":691931,"seconds":1716879778}}[0m
[37m[2024-05-28T07:02:58.749319Z] [debug] [pid:130043] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"51734","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"6007","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":692961,"seconds":1716879778}}[0m
[37m[2024-05-28T07:02:58.749396Z] [debug] [pid:130043] EVENT {"event":"RESUME","timestamp":{"microseconds":749030,"seconds":1716879778}}[0m
GOT GO

[37m[2024-05-28T07:02:58.754101Z] [debug] [pid:130043] QEMU: QEMU emulator version 7.1.0 (SUSE Linux Enterprise 15)[0m
[37m[2024-05-28T07:02:58.754149Z] [debug] [pid:130043] QEMU: Copyright (c) 2003-2022 Fabrice Bellard and the QEMU Project developers[0m
[37m[2024-05-28T07:02:58.756648Z] [debug] [pid:129853] Snapshots are supported[0m
[1;34m[2024-05-28T07:02:58.757471Z] [debug] [pid:129853] ||| starting boot_linuxrc tests/boot/boot_linuxrc.pm[0m
[2024-05-28T07:02:58.758690Z] [debug] [pid:129853] tests/boot/boot_linuxrc.pm:17 called bootloader_setup::ensure_shim_import -> lib/bootloader_setup.pm:1292 called testapi::assert_screen
[2024-05-28T07:02:58.758973Z] [debug] [pid:129853] <<< testapi::assert_screen(mustmatch=[
    "inst-bootmenu",
    "bootloader-shim-import-prompt"
  ], timeout=30)
[37m[2024-05-28T07:02:59.917574Z] [debug] [pid:130043] no match: 29.0s, best candidate: bootloader-shim-import-prompt-20221107 (0.30)[0m
Input #0, image2pipe, from 'pipe:':
  Duration: N/A, bitrate: N/A
  Stream #0:0: Video: ppm, rgb24, 1024x768, 24 fps, 24 tbr, 24 tbn, 24 tbc
Stream mapping:
  Stream #0:0 -> #0:0 (ppm (native) -> vp9 (libvpx-vp9))
[libvpx-vp9 @ 0x55d5b12b1900] v1.11.0
Output #0, webm, to 'video.webm':
  Metadata:
    encoder         : Lavf58.76.100
  Stream #0:0: Video: vp9, yuv420p(tv, progressive), 1024x768, q=2-31, 1500 kb/s, 24 fps, 1k tbn
    Metadata:
      encoder         : Lavc58.134.100 libvpx-vp9
    Side data:
      cpb: bitrate max/min/avg: 0/0/0 buffer size: 0 vbv_delay: N/A
[37m[2024-05-28T07:03:00.868980Z] [debug] [pid:130043] no match: 28.0s, best candidate: bootloader-grub2-alp-selfinstall-20230327 (0.00)[0m
[32m[2024-05-28T07:03:01.926840Z] [debug] [pid:129853] >>> testapi::_handle_found_needle: found bootmenu-Slowroll-20240109, similarity 1.00 @ 0/0[0m
[2024-05-28T07:03:01.927920Z] [debug] [pid:129853] tests/boot/boot_linuxrc.pm:18 called bootloader_setup::select_bootmenu_more -> lib/bootloader_setup.pm:743 called bootloader_setup::stop_grub_timeout -> lib/bootloader_setup.pm:82 called testapi::send_key
[2024-05-28T07:03:01.928094Z] [debug] [pid:129853] <<< testapi::send_key(key="up", wait_screen_change=0)
[2024-05-28T07:03:02.197652Z] [debug] [pid:129853] tests/boot/boot_linuxrc.pm:18 called bootloader_setup::select_bootmenu_more -> lib/bootloader_setup.pm:746 called testapi::check_screen
[2024-05-28T07:03:02.197831Z] [debug] [pid:129853] <<< testapi::check_screen(mustmatch="inst-submenu-more", timeout=0)
[32m[2024-05-28T07:03:02.864779Z] [debug] [pid:129853] >>> testapi::_handle_found_needle: found inst-submenu-more-20191210, similarity 1.00 @ 242/255[0m
[2024-05-28T07:03:02.865510Z] [debug] [pid:129853] tests/boot/boot_linuxrc.pm:18 called bootloader_setup::select_bootmenu_more -> lib/bootloader_setup.pm:747 called testapi::send_key_until_needlematch
[2024-05-28T07:03:02.865617Z] [debug] [pid:129853] <<< testapi::check_screen(mustmatch="inst-onmore", timeout=0)
[37m[2024-05-28T07:03:03.853548Z] [debug] [pid:130043] no match: -0.9s, best candidate: inst-onmore-20191210 (0.43)[0m
[32m[2024-05-28T07:03:03.923Z] [debug] [pid:129853] >>> testapi::_check_backend_response: match=inst-onmore timed out after 0 (check_screen)[0m
[2024-05-28T07:03:03.939225Z] [debug] [pid:129853] tests/boot/boot_linuxrc.pm:18 called bootloader_setup::select_bootmenu_more -> lib/bootloader_setup.pm:747 called testapi::send_key_until_needlematch
[2024-05-28T07:03:03.939357Z] [debug] [pid:129853] <<< testapi::wait_screen_change(timeout=10, similarity_level=50)
[2024-05-28T07:03:03.940139Z] [debug] [pid:129853] tests/boot/boot_linuxrc.pm:18 called bootloader_setup::select_bootmenu_more -> lib/bootloader_setup.pm:747 called testapi::send_key_until_needlematch
[2024-05-28T07:03:03.940235Z] [debug] [pid:129853] <<< testapi::send_key(key="down", wait_screen_change=0)
[32m[2024-05-28T07:03:04.428471Z] [debug] [pid:129853] >>> testapi::wait_screen_change: screen change seen after 0.214343070983887 seconds (similarity: 25.4959252092494)[0m
[2024-05-28T07:03:04.428667Z] [debug] [pid:129853] tests/boot/boot_linuxrc.pm:18 called bootloader_setup::select_bootmenu_more -> lib/bootloader_setup.pm:747 called testapi::send_key_until_needlematch
[2024-05-28T07:03:04.428798Z] [debug] [pid:129853] <<< testapi::check_screen(mustmatch="inst-onmore", timeout=5)
[37m[2024-05-28T07:03:04.760787Z] [debug] [pid:130043] no match: 4.6s, best candidate: inst-onmore-20191210 (0.65)[0m
[37m[2024-05-28T07:03:05.755527Z] [debug] [pid:130043] no change: 3.6s[0m
[37m[2024-05-28T07:03:05.762391Z] [debug] [pid:130043] no match: 3.6s, best candidate: inst-onmore-20191210 (0.65)[0m
[37m[2024-05-28T07:03:06.756516Z] [debug] [pid:130043] no change: 2.6s[0m
[37m[2024-05-28T07:03:06.762321Z] [debug] [pid:130043] no match: 2.6s, best candidate: inst-onmore-20191210 (0.65)[0m
[37m[2024-05-28T07:03:07.757583Z] [debug] [pid:130043] no change: 1.6s[0m
[37m[2024-05-28T07:03:07.762932Z] [debug] [pid:130043] no match: 1.6s, best candidate: inst-onmore-20191210 (0.65)[0m
[37m[2024-05-28T07:03:08.832230Z] [debug] [pid:130043] no match: 0.6s, best candidate: inst-onmore-20191210 (0.65)[0m
[37m[2024-05-28T07:03:09.831993Z] [debug] [pid:130043] no match: -0.4s, best candidate: inst-onmore-20191210 (0.65)[0m
[32m[2024-05-28T07:03:09.925386Z] [debug] [pid:129853] >>> testapi::_check_backend_response: match=inst-onmore timed out after 5 (check_screen)[0m
[2024-05-28T07:03:09.940200Z] [debug] [pid:129853] tests/boot/boot_linuxrc.pm:18 called bootloader_setup::select_bootmenu_more -> lib/bootloader_setup.pm:747 called testapi::send_key_until_needlematch
[2024-05-28T07:03:09.940316Z] [debug] [pid:129853] <<< testapi::wait_screen_change(timeout=10, similarity_level=50)
[2024-05-28T07:03:09.941263Z] [debug] [pid:129853] tests/boot/boot_linuxrc.pm:18 called bootloader_setup::select_bootmenu_more -> lib/bootloader_setup.pm:747 called testapi::send_key_until_needlematch
[2024-05-28T07:03:09.941336Z] [debug] [pid:129853] <<< testapi::send_key(key="down", wait_screen_change=0)
[32m[2024-05-28T07:03:10.435470Z] [debug] [pid:129853] >>> testapi::wait_screen_change: screen change seen after 0.221405982971191 seconds (similarity: 26.020406387285)[0m
[2024-05-28T07:03:10.435637Z] [debug] [pid:129853] tests/boot/boot_linuxrc.pm:18 called bootloader_setup::select_bootmenu_more -> lib/bootloader_setup.pm:747 called testapi::send_key_until_needlematch
[2024-05-28T07:03:10.435786Z] [debug] [pid:129853] <<< testapi::check_screen(mustmatch="inst-onmore", timeout=5)
[37m[2024-05-28T07:03:10.766317Z] [debug] [pid:130043] no match: 4.6s, best candidate: inst-onmore-20191210 (0.65)[0m
[37m[2024-05-28T07:03:11.760419Z] [debug] [pid:130043] no change: 3.6s[0m
[37m[2024-05-28T07:03:11.765693Z] [debug] [pid:130043] no match: 3.6s, best candidate: inst-onmore-20191210 (0.65)[0m
[37m[2024-05-28T07:03:12.761500Z] [debug] [pid:130043] no change: 2.6s[0m
[37m[2024-05-28T07:03:12.766824Z] [debug] [pid:130043] no match: 2.6s, best candidate: inst-onmore-20191210 (0.65)[0m
[37m[2024-05-28T07:03:13.762549Z] [debug] [pid:130043] no change: 1.6s[0m
[37m[2024-05-28T07:03:13.767736Z] [debug] [pid:130043] no match: 1.6s, best candidate: inst-onmore-20191210 (0.65)[0m
[37m[2024-05-28T07:03:14.837475Z] [debug] [pid:130043] no match: 0.6s, best candidate: inst-onmore-20191210 (0.65)[0m
[37m[2024-05-28T07:03:15.839519Z] [debug] [pid:130043] no match: -0.4s, best candidate: inst-onmore-20191210 (0.65)[0m
[32m[2024-05-28T07:03:15.925209Z] [debug] [pid:129853] >>> testapi::_check_backend_response: match=inst-onmore timed out after 5 (check_screen)[0m
[2024-05-28T07:03:15.940017Z] [debug] [pid:129853] tests/boot/boot_linuxrc.pm:18 called bootloader_setup::select_bootmenu_more -> lib/bootloader_setup.pm:747 called testapi::send_key_until_needlematch
[2024-05-28T07:03:15.940132Z] [debug] [pid:129853] <<< testapi::wait_screen_change(timeout=10, similarity_level=50)
[2024-05-28T07:03:15.940618Z] [debug] [pid:129853] tests/boot/boot_linuxrc.pm:18 called bootloader_setup::select_bootmenu_more -> lib/bootloader_setup.pm:747 called testapi::send_key_until_needlematch
[2024-05-28T07:03:15.940691Z] [debug] [pid:129853] <<< testapi::send_key(key="down", wait_screen_change=0)
[32m[2024-05-28T07:03:16.444460Z] [debug] [pid:129853] >>> testapi::wait_screen_change: screen change seen after 0.22951602935791 seconds (similarity: 25.5912442702931)[0m
[2024-05-28T07:03:16.444691Z] [debug] [pid:129853] tests/boot/boot_linuxrc.pm:18 called bootloader_setup::select_bootmenu_more -> lib/bootloader_setup.pm:747 called testapi::send_key_until_needlematch
[2024-05-28T07:03:16.444893Z] [debug] [pid:129853] <<< testapi::check_screen(mustmatch="inst-onmore", timeout=5)
[32m[2024-05-28T07:03:16.823727Z] [debug] [pid:129853] >>> testapi::_handle_found_needle: found inst-onmore-20191210, similarity 1.00 @ 248/252[0m
[2024-05-28T07:03:16.823852Z] [debug] [pid:129853] tests/boot/boot_linuxrc.pm:18 called bootloader_setup::select_bootmenu_more -> lib/bootloader_setup.pm:748 called testapi::send_key
[2024-05-28T07:03:16.823955Z] [debug] [pid:129853] <<< testapi::send_key(key="ret", wait_screen_change=0)
[2024-05-28T07:03:17.092115Z] [debug] [pid:129853] tests/boot/boot_linuxrc.pm:18 called bootloader_setup::select_bootmenu_more -> lib/bootloader_setup.pm:750 called testapi::send_key_until_needlematch
[2024-05-28T07:03:17.092285Z] [debug] [pid:129853] <<< testapi::check_screen(mustmatch="inst-boot_linuxrc", timeout=0)
[37m[2024-05-28T07:03:17.863012Z] [debug] [pid:130043] no match: -0.7s, best candidate: boot_linuxrc-inst-boot_linuxrc-20191215 (0.42)[0m
[32m[2024-05-28T07:03:17.926520Z] [debug] [pid:129853] >>> testapi::_check_backend_response: match=inst-boot_linuxrc timed out after 0 (check_screen)[0m
[2024-05-28T07:03:17.939117Z] [debug] [pid:129853] tests/boot/boot_linuxrc.pm:18 called bootloader_setup::select_bootmenu_more -> lib/bootloader_setup.pm:750 called testapi::send_key_until_needlematch
[2024-05-28T07:03:17.939227Z] [debug] [pid:129853] <<< testapi::wait_screen_change(timeout=10, similarity_level=50)
[2024-05-28T07:03:17.941795Z] [debug] [pid:129853] tests/boot/boot_linuxrc.pm:18 called bootloader_setup::select_bootmenu_more -> lib/bootloader_setup.pm:750 called testapi::send_key_until_needlematch
[2024-05-28T07:03:17.941902Z] [debug] [pid:129853] <<< testapi::send_key(key="down", wait_screen_change=0)
[32m[2024-05-28T07:03:18.445568Z] [debug] [pid:129853] >>> testapi::wait_screen_change: screen change seen after 0.231007099151611 seconds (similarity: 25.8312055342432)[0m
[2024-05-28T07:03:18.445767Z] [debug] [pid:129853] tests/boot/boot_linuxrc.pm:18 called bootloader_setup::select_bootmenu_more -> lib/bootloader_setup.pm:750 called testapi::send_key_until_needlematch
[2024-05-28T07:03:18.445897Z] [debug] [pid:129853] <<< testapi::check_screen(mustmatch="inst-boot_linuxrc", timeout=3)
[32m[2024-05-28T07:03:18.824748Z] [debug] [pid:129853] >>> testapi::_handle_found_needle: found boot_linuxrc-inst-boot_linuxrc-20191215, similarity 1.00 @ 250/197[0m
[2024-05-28T07:03:18.825049Z] [debug] [pid:129853] tests/boot/boot_linuxrc.pm:18 called bootloader_setup::select_bootmenu_more -> lib/bootloader_setup.pm:771 called bootloader_setup::type_boot_parameters -> lib/bootloader_setup.pm:1592 called testapi::type_string
[2024-05-28T07:03:18.825246Z] [debug] [pid:129853] <<< testapi::type_string(string="  linuxrc.log=/dev/ttyS0 linuxrc.core=/dev/ttyS0 linuxrc.debug=4,trace  ", max_interval=4, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:03:57.845461Z] [debug] [pid:129853] tests/boot/boot_linuxrc.pm:18 called bootloader_setup::select_bootmenu_more -> lib/bootloader_setup.pm:773 called testapi::send_key
[2024-05-28T07:03:57.845594Z] [debug] [pid:129853] <<< testapi::send_key(key="ret", wait_screen_change=0)
[2024-05-28T07:03:58.113432Z] [debug] [pid:129853] tests/boot/boot_linuxrc.pm:20 called testapi::assert_screen
[2024-05-28T07:03:58.113584Z] [debug] [pid:129853] <<< testapi::assert_screen(mustmatch="OK_button_linuxrc", timeout=120)
[37m[2024-05-28T07:03:58.118772Z] [debug] [pid:130043] no match: 119.9s, best candidate: boot_linuxrc-OK_button_linuxrc--TW-20190708 (0.00)[0m
[37m[2024-05-28T07:03:59.120324Z] [debug] [pid:130043] no match: 118.9s, best candidate: boot_linuxrc-OK_button_linuxrc--TW-20190708 (0.00)[0m
[37m[2024-05-28T07:04:00.123688Z] [debug] [pid:130043] no match: 117.9s, best candidate: boot_linuxrc-OK_button_linuxrc--TW-20190708 (0.00)[0m
[37m[2024-05-28T07:04:01.123468Z] [debug] [pid:130043] no match: 116.9s, best candidate: boot_linuxrc-OK_button_linuxrc--TW-20190708 (0.00)[0m
[37m[2024-05-28T07:04:02.049900Z] [debug] [pid:130043] pointer type 1 0 720 400 -257[0m
[37m[2024-05-28T07:04:02.140368Z] [debug] [pid:130043] no match: 115.9s, best candidate: boot_linuxrc-OK_button_linuxrc--TW-20190708 (0.00)[0m
[37m[2024-05-28T07:04:03.127609Z] [debug] [pid:130043] no match: 114.9s, best candidate: boot_linuxrc-OK_button_linuxrc--TW-20190708 (0.00)[0m
[37m[2024-05-28T07:04:04.127725Z] [debug] [pid:130043] no match: 113.9s, best candidate: boot_linuxrc-OK_button_linuxrc--TW-20190708 (0.00)[0m
[37m[2024-05-28T07:04:05.126685Z] [debug] [pid:130043] no match: 112.9s, best candidate: boot_linuxrc-OK_button_linuxrc--TW-20190708 (0.00)[0m
[37m[2024-05-28T07:04:06.128571Z] [debug] [pid:130043] no match: 111.9s, best candidate: boot_linuxrc-OK_button_linuxrc--TW-20190708 (0.00)[0m
[37m[2024-05-28T07:04:07.145469Z] [debug] [pid:130043] no match: 110.9s, best candidate: boot_linuxrc-OK_button_linuxrc--TW-20190708 (0.00)[0m
[37m[2024-05-28T07:04:08.130599Z] [debug] [pid:130043] no match: 109.9s, best candidate: boot_linuxrc-OK_button_linuxrc--TW-20190708 (0.00)[0m
[37m[2024-05-28T07:04:09.131065Z] [debug] [pid:130043] no match: 108.9s, best candidate: boot_linuxrc-OK_button_linuxrc--TW-20190708 (0.00)[0m
[37m[2024-05-28T07:04:10.125929Z] [debug] [pid:130043] no change: 107.9s[0m
[37m[2024-05-28T07:04:10.130712Z] [debug] [pid:130043] no match: 107.9s, best candidate: boot_linuxrc-OK_button_linuxrc--TW-20190708 (0.00)[0m
[37m[2024-05-28T07:04:11.133132Z] [debug] [pid:130043] no match: 106.9s, best candidate: boot_linuxrc-OK_button_linuxrc--TW-20190708 (0.00)[0m
[37m[2024-05-28T07:04:12.151335Z] [debug] [pid:130043] no match: 105.9s, best candidate: boot_linuxrc-OK_button_linuxrc--TW-20190708 (0.00)[0m
[37m[2024-05-28T07:04:13.134588Z] [debug] [pid:130043] no match: 104.9s, best candidate: boot_linuxrc-OK_button_linuxrc--TW-20190708 (0.00)[0m
[37m[2024-05-28T07:04:14.134536Z] [debug] [pid:130043] no match: 103.9s, best candidate: boot_linuxrc-OK_button_linuxrc--TW-20190708 (0.00)[0m
[37m[2024-05-28T07:04:15.136731Z] [debug] [pid:130043] no match: 102.9s, best candidate: boot_linuxrc-OK_button_linuxrc--TW-20190708 (0.00)[0m
[37m[2024-05-28T07:04:16.136568Z] [debug] [pid:130043] no match: 101.9s, best candidate: boot_linuxrc-OK_button_linuxrc--TW-20190708 (0.00)[0m
[37m[2024-05-28T07:04:17.156962Z] [debug] [pid:130043] no match: 100.9s, best candidate: boot_linuxrc-OK_button_linuxrc--TW-20190708 (0.00)[0m
[37m[2024-05-28T07:04:18.138805Z] [debug] [pid:130043] no match: 99.9s, best candidate: boot_linuxrc-OK_button_linuxrc--TW-20190708 (0.00)[0m
[37m[2024-05-28T07:04:19.139133Z] [debug] [pid:130043] no match: 98.9s, best candidate: boot_linuxrc-OK_button_linuxrc--TW-20190708 (0.00)[0m
[37m[2024-05-28T07:04:20.141008Z] [debug] [pid:130043] no match: 97.9s, best candidate: boot_linuxrc-OK_button_linuxrc--TW-20190708 (0.00)[0m
[37m[2024-05-28T07:04:21.142194Z] [debug] [pid:130043] no match: 96.9s, best candidate: boot_linuxrc-OK_button_linuxrc--TW-20190708 (0.00)[0m
[37m[2024-05-28T07:04:22.160375Z] [debug] [pid:130043] no match: 95.9s, best candidate: boot_linuxrc-OK_button_linuxrc--TW-20190708 (0.00)[0m
[37m[2024-05-28T07:04:23.142348Z] [debug] [pid:130043] no match: 94.9s, best candidate: boot_linuxrc-OK_button_linuxrc--TW-20190708 (0.00)[0m
[37m[2024-05-28T07:04:24.143759Z] [debug] [pid:130043] no match: 93.9s, best candidate: boot_linuxrc-OK_button_linuxrc--TW-20190708 (0.00)[0m
[37m[2024-05-28T07:04:25.145561Z] [debug] [pid:130043] no match: 92.9s, best candidate: boot_linuxrc-OK_button_linuxrc--TW-20190708 (0.00)[0m
[37m[2024-05-28T07:04:26.146853Z] [debug] [pid:130043] no match: 91.9s, best candidate: boot_linuxrc-OK_button_linuxrc--TW-20190708 (0.00)[0m
[37m[2024-05-28T07:04:27.164491Z] [debug] [pid:130043] no match: 90.9s, best candidate: boot_linuxrc-OK_button_linuxrc--TW-20190708 (0.00)[0m
[37m[2024-05-28T07:04:28.149041Z] [debug] [pid:130043] no match: 89.9s, best candidate: boot_linuxrc-OK_button_linuxrc--TW-20190708 (0.00)[0m
[37m[2024-05-28T07:04:29.149910Z] [debug] [pid:130043] no match: 88.9s, best candidate: boot_linuxrc-OK_button_linuxrc--TW-20190708 (0.00)[0m
[37m[2024-05-28T07:04:30.150537Z] [debug] [pid:130043] no match: 87.9s, best candidate: boot_linuxrc-OK_button_linuxrc--TW-20190708 (0.00)[0m
[32m[2024-05-28T07:04:31.192277Z] [debug] [pid:129853] >>> testapi::_handle_found_needle: found boot_linuxrc-OK_button_linuxrc--TW-20190708, similarity 1.00 @ 363/461[0m
[2024-05-28T07:04:31.192426Z] [debug] [pid:129853] tests/boot/boot_linuxrc.pm:21 called testapi::send_key
[2024-05-28T07:04:31.192546Z] [debug] [pid:129853] <<< testapi::send_key(key="ret", wait_screen_change=0)
[2024-05-28T07:04:31.461002Z] [debug] [pid:129853] tests/boot/boot_linuxrc.pm:20 called testapi::assert_screen
[2024-05-28T07:04:31.461250Z] [debug] [pid:129853] <<< testapi::assert_screen(mustmatch="OK_button_linuxrc", timeout=120)
[32m[2024-05-28T07:04:32.189332Z] [debug] [pid:129853] >>> testapi::_handle_found_needle: found boot_linuxrc-OK_button_linuxrc--TW-20190708, similarity 1.00 @ 363/461[0m
[2024-05-28T07:04:32.189473Z] [debug] [pid:129853] tests/boot/boot_linuxrc.pm:21 called testapi::send_key
[2024-05-28T07:04:32.189592Z] [debug] [pid:129853] <<< testapi::send_key(key="ret", wait_screen_change=0)
[2024-05-28T07:04:32.458076Z] [debug] [pid:129853] tests/boot/boot_linuxrc.pm:20 called testapi::assert_screen
[2024-05-28T07:04:32.458240Z] [debug] [pid:129853] <<< testapi::assert_screen(mustmatch="OK_button_linuxrc", timeout=120)
[32m[2024-05-28T07:04:33.192488Z] [debug] [pid:129853] >>> testapi::_handle_found_needle: found boot_linuxrc-OK_button_linuxrc--TW-20190708, similarity 1.00 @ 363/509[0m
[2024-05-28T07:04:33.192620Z] [debug] [pid:129853] tests/boot/boot_linuxrc.pm:21 called testapi::send_key
[2024-05-28T07:04:33.192730Z] [debug] [pid:129853] <<< testapi::send_key(key="ret", wait_screen_change=0)
[2024-05-28T07:04:33.461040Z] [debug] [pid:129853] tests/boot/boot_linuxrc.pm:23 called testapi::assert_screen
[2024-05-28T07:04:33.461226Z] [debug] [pid:129853] <<< testapi::assert_screen(mustmatch="edit_kernel_options", timeout=30)
[32m[2024-05-28T07:04:34.199790Z] [debug] [pid:129853] >>> testapi::_handle_found_needle: found boot_linuxrc-edit_kernel_options-TW-20190708, similarity 1.00 @ 433/354[0m
[2024-05-28T07:04:34.199954Z] [debug] [pid:129853] tests/boot/boot_linuxrc.pm:24 called testapi::send_key
[2024-05-28T07:04:34.200105Z] [debug] [pid:129853] <<< testapi::send_key(key="ret", wait_screen_change=0)
[2024-05-28T07:04:34.468324Z] [debug] [pid:129853] tests/boot/boot_linuxrc.pm:25 called testapi::assert_screen
[2024-05-28T07:04:34.468497Z] [debug] [pid:129853] <<< testapi::assert_screen(mustmatch="edit_kexec_options", timeout=30)
[32m[2024-05-28T07:04:35.194418Z] [debug] [pid:129853] >>> testapi::_handle_found_needle: found boot_linuxrc-edit_kexec_options-20190716, similarity 1.00 @ 529/353[0m
[2024-05-28T07:04:35.194548Z] [debug] [pid:129853] tests/boot/boot_linuxrc.pm:26 called testapi::send_key
[2024-05-28T07:04:35.194654Z] [debug] [pid:129853] <<< testapi::send_key(key="ret", wait_screen_change=0)
[1;34m[2024-05-28T07:04:35.468517Z] [debug] [pid:129853] ||| finished boot_linuxrc boot (runtime: 97 s)[0m
[1;34m[2024-05-28T07:04:35.469903Z] [debug] [pid:129853] ||| starting first_boot tests/installation/first_boot.pm[0m
[2024-05-28T07:04:35.470732Z] [debug] [pid:129853] tests/installation/first_boot.pm:23 called opensusebasetest::wait_boot_past_bootloader -> lib/opensusebasetest.pm:818 called testapi::check_screen
[2024-05-28T07:04:35.470862Z] [debug] [pid:129853] <<< testapi::check_screen(mustmatch=[
    "generic-desktop",
    "emergency-shell",
    "emergency-mode",
    "opensuse-welcome"
  ], timeout=30)
[31m[2024-05-28T07:04:38.841262Z] [warn] [pid:130043] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.69 seconds for 98 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:04:38.841346Z] [debug] [pid:130043] no match: 29.3s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[31m[2024-05-28T07:04:40.164582Z] [warn] [pid:130043] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.31 seconds for 98 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:04:40.164678Z] [debug] [pid:130043] no match: 26.6s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[31m[2024-05-28T07:04:45.038955Z] [warn] [pid:130043] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 4.87 seconds for 98 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:04:45.039039Z] [debug] [pid:130043] no match: 25.2s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[31m[2024-05-28T07:04:49.869379Z] [warn] [pid:130043] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 4.82 seconds for 98 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:04:49.869480Z] [debug] [pid:130043] no match: 20.4s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[31m[2024-05-28T07:04:54.602218Z] [warn] [pid:130043] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 4.73 seconds for 98 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:04:54.602317Z] [debug] [pid:130043] no match: 15.5s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[31m[2024-05-28T07:04:59.344722Z] [warn] [pid:130043] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 4.74 seconds for 98 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:04:59.344821Z] [debug] [pid:130043] no match: 10.8s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[31m[2024-05-28T07:05:00.739196Z] [warn] [pid:130043] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.39 seconds for 98 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:00.739287Z] [debug] [pid:130043] no match: 6.1s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[31m[2024-05-28T07:05:02.141599Z] [warn] [pid:130043] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.40 seconds for 98 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:02.141684Z] [debug] [pid:130043] no match: 4.7s, best candidate: generic-desktop-kde-leap155-updated_from_leap42.1-20220919 (0.00)[0m
[31m[2024-05-28T07:05:03.532174Z] [warn] [pid:130043] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.39 seconds for 98 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:03.532263Z] [debug] [pid:130043] no match: 3.3s, best candidate: generic-desktop-kde-leap155-updated_from_leap42.1-20220919 (0.00)[0m
[31m[2024-05-28T07:05:04.944370Z] [warn] [pid:130043] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.41 seconds for 98 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:04.944458Z] [debug] [pid:130043] no match: 1.9s, best candidate: generic-desktop-kde-leap155-updated_from_leap42.1-20220919 (0.00)[0m
[31m[2024-05-28T07:05:10.186491Z] [warn] [pid:130043] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.24 seconds for 98 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:10.186573Z] [debug] [pid:130043] no match: 0.5s, best candidate: generic-desktop-kde-leap155-updated_from_leap42.1-20220919 (0.00)[0m
[31m[2024-05-28T07:05:14.842603Z] [warn] [pid:130043] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 4.65 seconds for 98 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:14.842702Z] [debug] [pid:130043] no match: -4.8s, best candidate: generic-desktop-kde-leap155-updated_from_leap42.1-20220919 (0.00)[0m
[32m[2024-05-28T07:05:15.107614Z] [debug] [pid:129853] >>> testapi::_check_backend_response: match=emergency-mode,emergency-shell,generic-desktop,opensuse-welcome timed out after 30 (check_screen)[0m
[2024-05-28T07:05:15.130783Z] [debug] [pid:129853] tests/installation/first_boot.pm:23 called opensusebasetest::wait_boot_past_bootloader -> lib/opensusebasetest.pm:818 called testapi::check_screen
[2024-05-28T07:05:15.130963Z] [debug] [pid:129853] <<< testapi::check_screen(mustmatch=[
    "generic-desktop",
    "emergency-shell",
    "emergency-mode",
    "opensuse-welcome"
  ], timeout=30)
[32m[2024-05-28T07:05:17.312687Z] [debug] [pid:129853] >>> testapi::_handle_found_needle: found generic-desktop-plasma-20240318, similarity 1.00 @ 0/0[0m
[2024-05-28T07:05:17.314162Z] [debug] [pid:129853] tests/installation/first_boot.pm:26 called x11utils::turn_off_plasma_tooltips -> lib/x11utils.pm:440 called testapi::x11_start_program
[2024-05-28T07:05:17.314333Z] [debug] [pid:129853] <<< testapi::x11_start_program(program="kwriteconfig6 --file plasmarc --group PlasmaToolTips --key Delay -- -1", target_match="generic-desktop", no_wait=1)
[2024-05-28T07:05:17.314596Z] [debug] [pid:129853] tests/installation/first_boot.pm:26 called x11utils::turn_off_plasma_tooltips -> lib/x11utils.pm:440 called testapi::x11_start_program -> lib/susedistribution.pm:295 called susedistribution::init_desktop_runner -> lib/susedistribution.pm:206 called testapi::send_key
[2024-05-28T07:05:17.314697Z] [debug] [pid:129853] <<< testapi::send_key(key="alt-f2", wait_screen_change=0)
[2024-05-28T07:05:17.650003Z] [debug] [pid:129853] tests/installation/first_boot.pm:26 called x11utils::turn_off_plasma_tooltips -> lib/x11utils.pm:440 called testapi::x11_start_program -> lib/susedistribution.pm:295 called susedistribution::init_desktop_runner -> lib/susedistribution.pm:208 called testapi::mouse_hide
[2024-05-28T07:05:17.650178Z] [debug] [pid:129853] <<< testapi::mouse_hide(border_offset=1)
[37m[2024-05-28T07:05:17.650718Z] [debug] [pid:130043] mouse_move 1022, 766[0m
[37m[2024-05-28T07:05:17.650793Z] [debug] [pid:130043] send_pointer_event 0, 1022, 766, 1[0m
[2024-05-28T07:05:17.651166Z] [debug] [pid:129853] tests/installation/first_boot.pm:26 called x11utils::turn_off_plasma_tooltips -> lib/x11utils.pm:440 called testapi::x11_start_program -> lib/susedistribution.pm:295 called susedistribution::init_desktop_runner -> lib/susedistribution.pm:209 called testapi::check_screen
[2024-05-28T07:05:17.651291Z] [debug] [pid:129853] <<< testapi::check_screen(mustmatch="desktop-runner", timeout=30)
[37m[2024-05-28T07:05:18.005543Z] [debug] [pid:130043] no match: 29.9s, best candidate: desktop-runner-kde-20210916 (0.29)[0m
[32m[2024-05-28T07:05:18.762836Z] [debug] [pid:129853] >>> testapi::_handle_found_needle: found desktop-runner-kde-20221212, similarity 0.98 @ 236/0[0m
[2024-05-28T07:05:18.763056Z] [debug] [pid:129853] tests/installation/first_boot.pm:26 called x11utils::turn_off_plasma_tooltips -> lib/x11utils.pm:440 called testapi::x11_start_program -> lib/susedistribution.pm:295 called susedistribution::init_desktop_runner -> lib/susedistribution.pm:214 called testapi::wait_still_screen
[2024-05-28T07:05:18.763172Z] [debug] [pid:129853] <<< testapi::wait_still_screen(stilltime=2, similarity_level=47, timeout=30)
[32m[2024-05-28T07:05:20.767123Z] [debug] [pid:129853] >>> testapi::wait_still_screen: detected same image for 2 seconds (2.00145483016968 s elapsed), last detected similarity is 1000000[0m
[2024-05-28T07:05:20.767453Z] [debug] [pid:129853] tests/installation/first_boot.pm:26 called x11utils::turn_off_plasma_tooltips -> lib/x11utils.pm:440 called testapi::x11_start_program -> lib/susedistribution.pm:295 called susedistribution::init_desktop_runner -> lib/susedistribution.pm:227 called utils::type_string_slow -> lib/utils.pm:479 called testapi::type_string
[2024-05-28T07:05:20.767743Z] [debug] [pid:129853] <<< testapi::type_string(string="kwriteconfig6 --file plasmarc --group PlasmaToolTips --key Delay -- -1", max_interval=13, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:05:43.183290Z] [debug] [pid:129853] tests/installation/first_boot.pm:26 called x11utils::turn_off_plasma_tooltips -> lib/x11utils.pm:440 called testapi::x11_start_program -> lib/susedistribution.pm:295 called susedistribution::init_desktop_runner -> lib/susedistribution.pm:237 called testapi::check_screen
[2024-05-28T07:05:43.183490Z] [debug] [pid:129853] <<< testapi::check_screen(mustmatch="desktop-runner-plasma-suggestions", timeout=30)
[32m[2024-05-28T07:05:43.400642Z] [debug] [pid:129853] >>> testapi::_handle_found_needle: found desktop-runner-plasma-suggestions-20240315, similarity 0.98 @ 233/4[0m
[2024-05-28T07:05:43.400840Z] [debug] [pid:129853] tests/installation/first_boot.pm:26 called x11utils::turn_off_plasma_tooltips -> lib/x11utils.pm:440 called testapi::x11_start_program -> lib/susedistribution.pm:302 called testapi::wait_still_screen
[2024-05-28T07:05:43.400957Z] [debug] [pid:129853] <<< testapi::wait_still_screen(stilltime=3, timeout=30, similarity_level=47)
[32m[2024-05-28T07:05:47.044326Z] [debug] [pid:129853] >>> testapi::wait_still_screen: detected same image for 3 seconds (3.63825988769531 s elapsed), last detected similarity is 1000000[0m
[2024-05-28T07:05:47.091796Z] [debug] [pid:129853] tests/installation/first_boot.pm:26 called x11utils::turn_off_plasma_tooltips -> lib/x11utils.pm:440 called testapi::x11_start_program -> lib/susedistribution.pm:304 called testapi::send_key
[2024-05-28T07:05:47.091948Z] [debug] [pid:129853] <<< testapi::send_key(key="ret", wait_screen_change=0)
[2024-05-28T07:05:47.360719Z] [debug] [pid:129853] tests/installation/first_boot.pm:26 called x11utils::turn_off_plasma_tooltips -> lib/x11utils.pm:440 called testapi::x11_start_program -> lib/susedistribution.pm:313 called testapi::assert_screen
[2024-05-28T07:05:47.360949Z] [debug] [pid:129853] <<< testapi::assert_screen(mustmatch=[
    "generic-desktop",
    "desktop-runner-plasma-suggestions"
  ], timeout=90, no_wait=0)
[32m[2024-05-28T07:05:48.291855Z] [debug] [pid:129853] >>> testapi::_handle_found_needle: found desktop-runner-plasma-suggestions-20221212, similarity 0.98 @ 233/4[0m
[2024-05-28T07:05:48.292304Z] [debug] [pid:129853] tests/installation/first_boot.pm:26 called x11utils::turn_off_plasma_tooltips -> lib/x11utils.pm:440 called testapi::x11_start_program -> lib/susedistribution.pm:317 called testapi::wait_screen_change
[2024-05-28T07:05:48.292406Z] [debug] [pid:129853] <<< testapi::wait_screen_change(timeout=10, similarity_level=50)
[2024-05-28T07:05:48.293065Z] [debug] [pid:129853] tests/installation/first_boot.pm:26 called x11utils::turn_off_plasma_tooltips -> lib/x11utils.pm:440 called testapi::x11_start_program -> lib/susedistribution.pm:317 called testapi::wait_screen_change -> lib/susedistribution.pm:316 called testapi::send_key
[2024-05-28T07:05:48.293137Z] [debug] [pid:129853] <<< testapi::send_key(key="ret", wait_screen_change=0)
[32m[2024-05-28T07:05:58.791376Z] [debug] [pid:129853] >>> testapi::wait_screen_change: timed out after 10.2266499996185 seconds (similarity: 1000000)[0m
[2024-05-28T07:05:58.844575Z] [debug] [pid:129853] tests/installation/first_boot.pm:26 called x11utils::turn_off_plasma_tooltips -> lib/x11utils.pm:440 called testapi::x11_start_program -> lib/susedistribution.pm:313 called testapi::assert_screen
[2024-05-28T07:05:58.844744Z] [debug] [pid:129853] <<< testapi::assert_screen(mustmatch=[
    "generic-desktop",
    "desktop-runner-plasma-suggestions",
    "desktop-runner-plasma-suggestions"
  ], no_wait=0, timeout=90)
[32m[2024-05-28T07:05:59.582324Z] [debug] [pid:129853] >>> testapi::_handle_found_needle: found generic-desktop-plasma-20240318, similarity 1.00 @ 0/0[0m
[1;34m[2024-05-28T07:05:59.583061Z] [debug] [pid:129853] ||| finished first_boot installation (runtime: 84 s)[0m
[37m[2024-05-28T07:05:59.586055Z] [debug] [pid:129823] stopping autotest process 129853[0m
[37m[2024-05-28T07:05:59.595657Z] [debug] [pid:129823] [autotest] process exited: 0[0m
[37m[2024-05-28T07:05:59.695908Z] [debug] [pid:129823] done with autotest process[0m
[37m[2024-05-28T07:05:59.696241Z] [debug] [pid:129823] stopping command server 129833 because test execution ended[0m
[37m[2024-05-28T07:05:59.696311Z] [debug] [pid:129823] isotovideo: informing websocket clients before stopping command server: http://127.0.0.1:20173/F46TXgXwXVTzH3Fh/broadcast[0m
[37m[2024-05-28T07:06:00.672534Z] [debug] [pid:129823] commands process exited: 0[0m
[37m[2024-05-28T07:06:00.772860Z] [debug] [pid:129823] done with command server[0m
[37m[2024-05-28T07:06:00.772933Z] [debug] [pid:129823] isotovideo done[0m
[37m[2024-05-28T07:06:00.773407Z] [debug] [pid:130043] EVENT {"data":{"path":"\/machine\/peripheral-anon\/device[3]\/virtio-backend"},"event":"NIC_RX_FILTER_CHANGED","timestamp":{"microseconds":45138,"seconds":1716879889}}[0m
[37m[2024-05-28T07:06:00.773524Z] [debug] [pid:130043] EVENT {"data":{"offset":-1,"qom-path":"\/machine\/unattached\/device[8]"},"event":"RTC_CHANGE","timestamp":{"microseconds":47176,"seconds":1716879894}}[0m
[37m[2024-05-28T07:06:00.773713Z] [debug] [pid:130043] QEMU status is not 'shutdown', it is 'running'[0m
[37m[2024-05-28T07:06:00.773842Z] [debug] [pid:129823] backend shutdown state: [0m
[33m[2024-05-28T07:06:00.774186Z] [info] [pid:130043] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json[0m
[37m[2024-05-28T07:06:01.831678Z] [debug] [pid:130043] Passing remaining frames to the video encoder[0m
frame=  278 fps=1.5 q=0.0 Lsize=     473kB time=00:00:11.54 bitrate= 335.7kbits/s speed=0.0632x    
video:471kB audio:0kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: 0.505871%
[37m[2024-05-28T07:06:02.597204Z] [debug] [pid:130043] Waiting for video encoder to finalize the video[0m
[37m[2024-05-28T07:06:02.597283Z] [debug] [pid:130043] The external video encoder (pid 130247) terminated[0m
[37m[2024-05-28T07:06:02.597333Z] [debug] [pid:130043] The built-in video encoder (pid 130248) terminated[0m
[37m[2024-05-28T07:06:02.597791Z] [debug] [pid:130043] QEMU: qemu-system-x86_64: terminating on signal 15 from pid 130043 (/usr/bin/isotovideo: backen)[0m
[37m[2024-05-28T07:06:02.598519Z] [debug] [pid:130043] sending magic and exit[0m
[37m[2024-05-28T07:06:02.598755Z] [debug] [pid:129823] received magic close[0m
[37m[2024-05-28T07:06:02.630476Z] [debug] [pid:129823] backend process exited: 0[0m
Use of uninitialized value $name in pattern match (m//) at /usr/lib/os-autoinst/OpenQA/Isotovideo/Utils.pm line 332.
	OpenQA::Isotovideo::Utils::handle_generated_assets(OpenQA::Isotovideo::CommandHandler=HASH(0x55fd1f69b0a0), "") called at /usr/bin/isotovideo line 204
	eval {...} called at /usr/bin/isotovideo line 161
[37m[2024-05-28T07:06:02.731603Z] [debug] [pid:129823] stopping backend process 130043[0m
[37m[2024-05-28T07:06:02.731664Z] [debug] [pid:129823] done with backend process[0m
129823: EXIT 0
[2024-05-28T07:06:02.778309Z] [info] Isotovideo exit status: 0
[2024-05-28T07:06:02.800478Z] [info] +++ worker notes +++
[2024-05-28T07:06:02.800585Z] [info] End time: 2024-05-28 07:06:02
[2024-05-28T07:06:02.800647Z] [info] Result: done
[2024-05-28T07:06:02.804919Z] [info] Uploading video.webm
[2024-05-28T07:06:02.852306Z] [info] Uploading autoinst-log.txt
